Fix timeout issues #699 #700

dugwood · 2016-10-12T21:45:22Z

Type of change

Description of change

If all bidders respond within the timeout, the callback is called again as the end of the timer, because it's not cleared. Hence the second auction ends too early.
Also, another bug fix: when an auction is running and another adUnit is sent to requestBids, the timeout was wrongly set as cbTimeout instead of timeout

New fixes:

remove old bids when same adUnitCode is called again
fixed getBidSetForBidder() so that it returns the good bid and fixes the timeout issue in Bid response times are sometimes wrong #643

Other information

@mkendall07
#699

dugwood · 2016-10-13T14:38:11Z

Don't merge for now, there's still a bug... I'll check for «bidsBackAll()» to clear the timeout.

dugwood · 2016-10-13T14:49:02Z

The issue lies in bidsBackAll(): it counts all bids received, hence the callback is called too early. So my fix is good, but there's something wrong with bidsBackAll.

dugwood · 2016-10-13T15:02:54Z

If I add:

if (bidsBackAll()) {
    console.log('all bids are back!');
    this.executeCallback();
}

and in bidsBackAdUnit():

console.log('all for unit ' + adUnitCode, requested === received);
return requested === received;

I get:

all for unit sas_438 false
all for unit sas_438 false
all for unit sas_438 false
all for unit sas_438 true
unit is full!
all bids are back!

And the second one which is launched as soon as the first auction finished:

all for unit sas_439 false
all bids are back!

So bidsBackAdUnit() works well (only one bid is back out of 4 bidders), but bidsBackAll() send a wrong answer.

Currently working on a fix... That may fix this too: #496

dugwood · 2016-10-13T15:36:17Z

The issue lies in the fact that removeComplete() correctly removes pbjs._bidsRequested but not pbjs._bidsReceived. A bid should not be removed from requested if it's not removed from received. Else the requested === received may be true because received wasn't cleared.

dugwood · 2016-10-13T17:26:32Z

removeComplete() removes entries even if there is no call to markComplete(). I'm about to fix it!

dugwood · 2016-10-13T18:34:04Z

@mkendall07 can your review my fixes please?

added a clearTimeout so that callback is run only once
fixed the removeComplete() which was removing bids not completed from the requested ones
fixed the timeout on auction when an auction is already running

dugwood · 2016-10-13T21:32:40Z

Can't fix for now... see comments in #699

To me markComplete and removeComplete should be removed and replaced by a simple pbjs._bidsRequested = pbjs._bidsReceived = []; in the clearAuction().

mercuryyy · 2016-10-13T22:47:08Z

this looks significant! did you A/B test impressions lost with and without this fix?

dugwood · 2016-10-14T05:37:38Z

@mercuryyy for now this fix isn't working at all. Still have issues with markComplete/removeComplete. I'm fixing it right now, and I'll remove some of the fixes I've done (some are useless in the new scenario I'm thinking about). But there's clearly a big issue here, when timeouts are not cleared or bidders don't answer.

dugwood · 2016-10-14T07:21:04Z

Sorry forgot to run the tests :-) But fix is working fine to me! So... back on tests!

dugwood · 2016-10-14T08:33:02Z

Why are adUnitCodes not passed in the requestBids() tests? Shouldn't it be set?

dugwood · 2016-10-15T20:40:38Z

@mkendall07 @matthewlane can you add the need review on this PR please?

This fix is useful for all users of multiple calls to the callback. For example for users of infinite scroll.

Thanks for your time.

protonate · 2016-10-19T23:10:50Z

src/prebid.js

-    bidmanager.addOneTimeCallback(bidsBackHandler);
+  auctionRunning = true;
+  for (let i = 0; i < adUnitCodes.length; i++) {
+    removePreviousBids(adUnitCodes[i]);


As noted above we should avoid promoting adUnitCodes as a primary data structure. The initial call to pbjs.requestBids must supply adUnits. Thereafter bids can be requested with adUnitCodes but only for adUnits already defined. In this block, for example, removePreviousBids will only be invoked if there are adUnitCodes, which may not be the case. See the 'No adUnits configured..' log message on line 552. adUnits are assumed to be present, and if adUnitCodes are present they are only used to filter adUnits.

protonate · 2016-10-19T23:24:17Z

src/bidmanager.js

-function bidsBackAll() {
-  const requested = $$PREBID_GLOBAL$$._bidsRequested.map(bidSet => bidSet.bids.length).reduce(add, 0);
-  const received = $$PREBID_GLOBAL$$._bidsReceived.length;
+function bidsBack(adUnitCodes) {


In my testing this is called twice from addBidResponse, once with the adUnitCode of the bid response and once without arguments. In the latter case requested and received both evaluate to 0 which returns true from this function which in turn invokes the callback earlier than expected and repeatedly for each call to bidmanager.addBidResponse.

I'm in favor of combining the two bidsBack... functions. If adUnitCodes is not defined it could be derived from pbjs.adUnits, and a .filter function applied if an adUnitCode is supplied to bidsBack function.

Didn't see this issue with both zero values... But I'll look for a fix in received, which is the culprit in the case of two auctions (the second time the requested isn't filtered correctly).

protonate · 2016-10-20T20:27:56Z

src/bidmanager.js

@@ -71,10 +70,11 @@ function getBidSetForBidder(bidder) {
 exports.addBidResponse = function (adUnitCode, bid) {
  if (bid) {

+    const bidSet = getBidSetForBidder(bid.bidderCode, adUnitCode);


This could be expressed as
const { requestId, start } = getBidSetForBidder(bid.bidderCode, adUnitCode);

protonate · 2016-10-20T20:28:06Z

src/bidmanager.js

@@ -9,6 +9,7 @@ var objectType_function = 'function';
 var externalCallbackByAdUnitArr = [];
 var externalCallbackArr = [];
 var externalOneTimeCallback = null;
+var externalOneTimeCallbackTimer = false;


Ok for now, though I think we could consider a callbackHandler object with callback and timer function properties and externalCallback... array properties.

I've fixed this in #735

protonate · 2016-10-20T20:28:50Z

src/bidmanager.js

    triggerAdUnitCallbacks(bid.adUnitCode);
  }

-  if (bidsBackAll()) {
+  if (bidsBack()) {


As noted above this can evaluate to true when requested and received both evaluate to 0 .

protonate · 2016-10-20T20:28:53Z

src/bidmanager.js

@@ -222,6 +220,11 @@ exports.registerDefaultBidderSetting = function (bidderCode, defaultSetting) {
 };

 exports.executeCallback = function (timedOut) {
+  // if there's still a timeout running, clear it now
+  if (!timedOut && externalOneTimeCallbackTimer) {
+    clearTimeout(externalOneTimeCallbackTimer);


Great catch.

Fixed in #735

protonate · 2016-10-20T20:30:23Z

src/prebid.js

@@ -37,6 +37,7 @@ var eventValidators = {

 $$PREBID_GLOBAL$$._bidsRequested = [];
 $$PREBID_GLOBAL$$._bidsReceived = [];
+$$PREBID_GLOBAL$$._adUnitCodes = [];


We should avoid another primary data structure here and consider adUnitCodes to be derived from adUnits. The codes are a shorthand way of refreshing bids for a previously defined group of adUnits.

The issue here is that you can't know what adUnits are currently used in the current auction... But maybe that's because I've got rid of markComplete.

protonate · 2016-10-21T17:30:23Z

src/prebid.js

-}
-
-function removeComplete() {
+function removePreviousBids(adUnitCode) {


This raises the question of determining when bids are no longer valid. In removePreviousBids here you remove all bids for a placement if that placement is included in the auction about to start. The code that this replaces marks bids complete for a placement if pbjs.renderAd is called for that placement, which means we know the auction was run and the winning ad has been rendered. Those "complete" bids are only removed when a subsequent bid request is about to go out. This gives publishers as open a window as possible to call the reporting APIs for the most recent auction. Also, renderAd is the only definitive knowledge Prebid has of the ad delivery. There is currently no Prebid handler for an ad render when filled by ad server demand.

As noted here and here and with this PR, the approach results in some unexpected "old" bids. However consider the case that there is nothing invalid about these bids necessarily, and including them in auctions may be desirable. For example, take a given placement auction where the highest bid is $5. As it happens the ad server fills with it's own demand. A subsequent request for bids for the placement returns a winner of $4. The "old" $5 bid is still a valid bid as far as the bidder is concerned. Why should we exclude the bid from the current outgoing auction?

We are already throwing out some bids we perhaps shouldn't. Consider a case where Prebid demand fills a placement. The winner was a $10 bid, with a $5 bid behind it. A second request for bids goes out with a winner of $2. In this case we currently markComplete and removeComplete so the $5 bid is thrown out and not considered in the second auction. Again, as far as the bidder is concerned, that is a valid $5 bid for the placement. Should we throw it out?

dugwood · 2016-10-22T12:22:13Z

Thanks @protonate! I didn't expect such a review. You're right about a lot of points, I didn't think about the old bids that could be used again.

I'll split this into multiple pulls, I think it's better that way. I'll refer to all your points one after the other in my future pulls.

In #718 there's also the bug of bidsBackAll() that doesn't fire. My guess is that the filter is wrong. I've removed it in this very PR, but as I now understand the way you think it, I'll try to fix this accordindly. But there is a bug with the count of received vs requested, that's for sure.

dugwood · 2016-10-22T13:30:11Z

Closing this PR because it will be split in multiple little ones

Fix timeout issues #699

03d050a

jaiminpanchal27 assigned protonate Oct 13, 2016

dugwood added 2 commits October 13, 2016 19:49

Merge branch 'master' of ssh://github.com/prebid/Prebid.js

0541c63

Fix bidsBackAll that returns true because removeComplete is bugged

e47efec

dugwood added 2 commits October 14, 2016 07:49

Merge branch 'master' of ssh://github.com/prebid/Prebid.js

5eaa3a6

Fix for handling old bids

c73cbd6

Handle tests

fd9a6e7

dugwood mentioned this pull request Oct 14, 2016

Bid response times are sometimes wrong #643

Closed

matthewlane added the needs review label Oct 17, 2016

protonate suggested changes Oct 21, 2016

View reviewed changes

protonate mentioned this pull request Oct 21, 2016

Fix how it is determined whether all bid requests have been responded to #718

Closed

8 tasks

dugwood mentioned this pull request Oct 22, 2016

Fixed timeout issues #735

Merged

8 tasks

dugwood closed this Oct 22, 2016

dugwood mentioned this pull request Oct 22, 2016

Fix selected bid for the right timestamp #736

Merged

8 tasks

dugwood mentioned this pull request Nov 3, 2016

add workaround to prevent IX adapter from ending auction early #763

Merged

1 task

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix timeout issues #699 #700

Fix timeout issues #699 #700

dugwood commented Oct 12, 2016 •

edited

Loading

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

mercuryyy commented Oct 13, 2016

dugwood commented Oct 14, 2016

dugwood commented Oct 14, 2016

dugwood commented Oct 14, 2016 •

edited

Loading

dugwood commented Oct 15, 2016

protonate Oct 19, 2016

protonate Oct 19, 2016

protonate Oct 21, 2016

dugwood Oct 22, 2016

protonate Oct 20, 2016

dugwood Oct 22, 2016

protonate Oct 20, 2016

dugwood Oct 22, 2016

protonate Oct 20, 2016

protonate Oct 20, 2016

dugwood Oct 22, 2016

protonate Oct 20, 2016

dugwood Oct 22, 2016

protonate Oct 21, 2016

dugwood commented Oct 22, 2016

dugwood commented Oct 22, 2016

Fix timeout issues #699 #700

Fix timeout issues #699 #700

Conversation

dugwood commented Oct 12, 2016 • edited Loading

Type of change

Description of change

Other information

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

dugwood commented Oct 13, 2016

mercuryyy commented Oct 13, 2016

dugwood commented Oct 14, 2016

dugwood commented Oct 14, 2016

dugwood commented Oct 14, 2016 • edited Loading

dugwood commented Oct 15, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dugwood commented Oct 22, 2016

dugwood commented Oct 22, 2016

dugwood commented Oct 12, 2016 •

edited

Loading

dugwood commented Oct 14, 2016 •

edited

Loading